v8: emit backtrace when trap happens. by mathetake · Pull Request #66 · proxy-wasm/proxy-wasm-cpp-host

mathetake · 2020-10-13T09:38:55Z

This PR tries to implement the feature for emitting backtrace information when trap happens with V8 runtime. This would improve extension developers' debuggability dramatically.

summary

I fixed the bug in wasm-c-api implemented in V8 and the patch has been merged to the V8's upstream: https://chromium-review.googlesource.com/c/v8/v8/+/2465353. Now it's possible to extract backtrace information from V8 when trap happens when we link against the latest V8 commit.

The example message is like this:

[2020-10-13 18:06:53.750][2197326][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:29] Function: proxy_on_tick failed:
V8 message: Uncaught RuntimeError: unreachable
wasm backtrace:
  0:  0x178f - runtime._panic
  1:  0xb046 - main.three
  2:  0xb034 - main.two
  3:  0xb02a - main.one
  4:  0x962a - (*main.rootContext).OnTick
  5:  0x95f0 - proxy_on_tick

from the the following Go SDK's code:

func (ctx *rootContext) OnTick() {
	one()
}

func one() {
	two()
}

func two() {
	three()
}

func three() {
	panic("oh")
}

The way I implemented is

(1) use Trap::trace() API to get stacked function frames (which do not contain function names)
(2) use name custom section (ref. wasm-spec) to get actual function names combined with frame informations acquired in (1).

message design

I am not sure how the backtrace message should look like, so I would like to have opinions as much as possible.

As of now, I just followed the style of wasmtime where <unknown> is the module name subsection in the name custom section:

>> wasmtime run aa.wasm
panic: C
Error: failed to run main module `aa.wasm`

Caused by:
    0: failed to invoke command default
    1: wasm trap: unreachable
       wasm backtrace:
         0:  0x238 - <unknown>!runtime._panic
         1:  0x33c - <unknown>!main.B
         2:  0x332 - <unknown>!main.A
         3:  0x2ba - <unknown>!main.run
         4:  0x29c - <unknown>!_start

Future works

I guess compiler optimizations may make this useless sometimes. We should also consider using dwarf info (luckily C++/Rust/TinyGo seem to add dwarf infos in resulting binary by default)
WAVM seems to have the trace API too, so after the discussion here, I will work on it as well.

⚠️IMPORTANT NOTE⚠️

This would not work until link the host against the latest upstream of V8

patch https://chromium-review.googlesource.com/c/v8/v8/+/2465353
mirror: v8/v8@8deb0fd

PiotrSikora

Thanks, this looks great!

Regarding your questions:

I'm confused as to why enabling this feature would expose Wasm's stack to the public?
Yes, we should support this in WAVM as well.
I'd like to defer merging this until it's available in Chromium's BETA channel (so ~6 weeks or so?).

src/v8/v8.cc

mathetake · 2020-10-27T05:47:15Z

I'm confused as to why enabling this feature would expose Wasm's stack to the public?

Never mind, I just confused the meaning of "sandbox" in WASM. I edited the description

Signed-off-by: mathetake <takeshi@tetrate.io>

src/v8/v8.cc

Signed-off-by: mathetake <takeshi@tetrate.io>

…t into trace-print

src/v8/v8.cc

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake · 2020-12-10T23:32:55Z

Now the trace looks like this:

[2020-12-11 08:32:05.761][71282][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x17a9 - runtime._panic
  1:  0xb721 - command-line-arguments.f_10
  2:  0xb767 - command-line-arguments.f_9
  3:  0xb75d - command-line-arguments.f_8
  4:  0xb753 - command-line-arguments.f_7
  5:  0xb749 - command-line-arguments.f_6
  6:  0xb73f - command-line-arguments.f_5
  7:  0xb735 - command-line-arguments.f_4
  8:  0xb72b - command-line-arguments.f_3
  9:  0xb70f - command-line-arguments.f_2

src/v8/v8.cc

Signed-off-by: mathetake <takeshi@tetrate.io>

PiotrSikora

Thanks! LGTM sans typo.

src/v8/v8.cc

PiotrSikora · 2020-12-15T07:18:15Z

Could you re-kick the CI via an empty commit? It looks that CLA bot got stuck.

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake · 2020-12-15T07:20:53Z

done

PiotrSikora · 2020-12-15T07:33:33Z

src/v8/v8.cc

+        if (start + size != pos) {
+          // indicates the malformed function name subsection, so clear the stored indexes.
+          function_names_index_ = {};
+        }


Nit: if this fails then we should probably break from the loop, since we can't trust the pos anyway... But I just realized that we don't do this type of verification when parsing bytecode in other places, so feel free to drop this whole if block if you prefer.

yeah, we trust given binaries anywhere while parsing so far 😄 maybe we should decide and stick to whether or not validate binary or not.

will add break for now.

Signed-off-by: mathetake <takeshi@tetrate.io>

…t into trace-print

PiotrSikora · 2020-12-15T07:38:48Z

src/v8/v8.cc

+      if (*pos++ != 1) {
+        pos += parseVarint(pos, end);
+      } else {
+        auto size = parseVarint(pos, end);


Actually, we need to verify this value, i.e.:

if (size == static_cast<uint32_t>(-1) || pos + size > end) { function_names_index_ = {}; return; }

Also, use const auto to match rest of the code.

src/v8/v8.cc

Signed-off-by: mathetake <takeshi@tetrate.io>

src/v8/v8.cc

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake · 2020-12-15T08:17:04Z

wait, something's broken

src/v8/v8.cc

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake · 2020-12-15T08:23:17Z

now looks good 😄

[2020-12-15 17:22:49.972][1539808][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x179f - runtime._panic
  1:  0x9954 - (*command-line-arguments.helloWorld).OnTick
  2:  0x982b - proxy_on_tick
[2020-12-15 17:22:49.988][1539905][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: It's 1608020569988011716: random value: 3792979139630623504
[2020-12-15 17:22:49.988][1539905][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: panic: aa
[2020-12-15 17:22:49.988][1539905][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x179f - runtime._panic
  1:  0x9954 - (*command-line-arguments.helloWorld).OnTick
  2:  0x982b - proxy_on_tick
[2020-12-15 17:22:49.988][1539906][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: It's 1608020569988198834: random value: 2471483108428180821
[2020-12-15 17:22:49.988][1539906][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: panic: aa
[2020-12-15 17:22:49.988][1539906][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x179f - runtime._panic
  1:  0x9954 - (*command-line-arguments.helloWorld).OnTick
  2:  0x982b - proxy_on_tick

PiotrSikora self-requested a review October 13, 2020 20:09

PiotrSikora requested changes Oct 13, 2020

View reviewed changes

mathetake mentioned this pull request Oct 28, 2020

wavm: emit stack trace when an exception happens #84

Merged

mathetake added 6 commits November 4, 2020 11:18

v8: emit backtrace when trap happens

5cb8386

Signed-off-by: mathetake <takeshi@tetrate.io>

tidy up get_fail_message

73e14cb

Signed-off-by: mathetake <takeshi@tetrate.io>

review: rename, refactor

1b47c0e

Signed-off-by: mathetake <takeshi@tetrate.io>

review: simplify message emission

0a8a65f

Signed-off-by: mathetake <takeshi@tetrate.io>

review: build function name index in load()

256b844

Signed-off-by: mathetake <takeshi@tetrate.io>

align leading spaces like wavm

5cb4a07

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake force-pushed the trace-print branch from 590df70 to 5cb4a07 Compare November 4, 2020 02:25

mathetake added 2 commits November 12, 2020 11:36

Merge branch 'master' into trace-print

f0e7a1a

Tidy up trace message

155e5c7

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake changed the title ~~v8: emit backtrace when trap happens~~ V8: emit backtrace when trap happens Nov 17, 2020

mathetake added 4 commits November 17, 2020 12:17

Handle the case of having no name custom section

0ee805f

Signed-off-by: mathetake <takeshi@tetrate.io>

Merge branch 'master' into trace-print

59d816c

Merge branch 'master' into trace-print

6fbdbc6

Merge branch 'master' into trace-print

e2facc1

PiotrSikora reviewed Dec 7, 2020

View reviewed changes

src/v8/v8.cc Outdated Show resolved Hide resolved

mathetake added 2 commits December 7, 2020 20:02

Review: remove unnecessary 'this->'

9a555a0

Signed-off-by: mathetake <takeshi@tetrate.io>

Merge branch 'trace-print' of github.com:mathetake/proxy-wasm-cpp-hos…

5c28a0b

…t into trace-print

PiotrSikora reviewed Dec 10, 2020

View reviewed changes

src/v8/v8.cc Outdated Show resolved Hide resolved

Review: mv \n to the beginning of of trace

51fc718

Signed-off-by: mathetake <takeshi@tetrate.io>

PiotrSikora requested changes Dec 12, 2020

View reviewed changes

mathetake added 2 commits December 12, 2020 14:26

Review: remove the trailing newline in msg & fix style

bb8fd80

Signed-off-by: mathetake <takeshi@tetrate.io>

Review: add buildFunctionNameIndex member

a24e213

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake requested a review from PiotrSikora December 12, 2020 05:57

PiotrSikora approved these changes Dec 14, 2020

View reviewed changes

src/v8/v8.cc Outdated Show resolved Hide resolved

review: fix typo

4f815f5

Signed-off-by: mathetake <takeshi@tetrate.io>

mathetake force-pushed the trace-print branch from f2d9170 to 4f815f5 Compare December 15, 2020 07:20

Merge branch 'master' into trace-print

07c1351

PiotrSikora reviewed Dec 15, 2020

View reviewed changes

mathetake added 2 commits December 15, 2020 16:39

Break loop when name section is malformed

a31cfdf

Signed-off-by: mathetake <takeshi@tetrate.io>

Merge branch 'trace-print' of github.com:mathetake/proxy-wasm-cpp-hos…

b83089f

…t into trace-print

PiotrSikora reviewed Dec 15, 2020

View reviewed changes

mathetake added 2 commits December 15, 2020 16:51

Review: check the size of subsection

bcf2182

Signed-off-by: mathetake <takeshi@tetrate.io>

Return if malformed

6ea1604

Signed-off-by: mathetake <takeshi@tetrate.io>

PiotrSikora reviewed Dec 15, 2020

View reviewed changes

src/v8/v8.cc Show resolved Hide resolved

Review: check all the parsed value

63312af

Signed-off-by: mathetake <takeshi@tetrate.io>

PiotrSikora reviewed Dec 15, 2020

View reviewed changes

src/v8/v8.cc Outdated Show resolved Hide resolved

Remove unnecessary boundary check for func_index

afa45f0

Signed-off-by: mathetake <takeshi@tetrate.io>

PiotrSikora changed the title ~~V8: emit backtrace when trap happens~~ v8: emit backtrace when trap happens Dec 15, 2020

PiotrSikora changed the title ~~v8: emit backtrace when trap happens~~ v8: emit backtrace when trap happens. Dec 15, 2020

PiotrSikora merged commit c6c07ad into proxy-wasm:master Dec 15, 2020

mathetake deleted the trace-print branch December 15, 2020 08:36

mathetake mentioned this pull request Nov 18, 2021

Emit backtrace in runtime error message. wazero/wazero#54

Merged

Conversation

mathetake commented Oct 13, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

summary

message design

Future works

⚠️IMPORTANT NOTE⚠️

Uh oh!

PiotrSikora left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

mathetake commented Oct 27, 2020

Uh oh!

Uh oh!

Uh oh!

mathetake commented Dec 10, 2020

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

PiotrSikora left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

PiotrSikora commented Dec 15, 2020

Uh oh!

mathetake commented Dec 15, 2020

Uh oh!

PiotrSikora Dec 15, 2020

Choose a reason for hiding this comment

Uh oh!

mathetake Dec 15, 2020

Choose a reason for hiding this comment

Uh oh!

PiotrSikora Dec 15, 2020

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

mathetake commented Dec 15, 2020

Uh oh!

Uh oh!

mathetake commented Dec 15, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

mathetake commented Oct 13, 2020 •

edited

Loading